fix: the writing session scanned delete_vector sequentially, once per row group (#1146) - #1202
Conversation
… row group (commandprompt#1146) `delete_vector` gained a `_pkey` and its readers were switched to it, but `PgColumnarUpsertDeleteVector` kept passing `InvalidOid`. It runs once per row group, so a DELETE touching twenty groups took twenty sequential scans of the catalog -- the cost the index switch existed to remove, still paid by the session that did the writing. ATTRIBUTED WITH AN ELOG PROBE AT EVERY delete_vector SCAN SITE, not inferred from the totals. During the DELETE, bracketed by two log marks: PgColumnarUpsertDeleteVector 20 PgColumnarReadDeleteVectorList 40 PgColumnarReadDeleteVectorsForStorage 1 against seq_scan=20 idx_scan=41 for the catalog. 40 + 1 are the indexed reads and the twenty are that one site, with nothing left over. Afterwards: before seq_scan=20 idx_scan=41 after seq_scan=0 idx_scan=61 41 + 20 = 61, so every scan that was sequential is now indexed and none was lost. THE REGRESSION ARM HAS TO BE IN THE PYTEST HARNESS. Every `q` in the shell harness is its own psql, so the scan it measures is always made by a session that did no writing; the writing-session path is unobservable there whatever the arm asserts. The new test holds one connection across the DELETE and reads the counters as a delta over it, and resets BEFORE the DELETE rather than after -- resetting afterwards is what attributed these scans to the following SELECT when they were first measured. The arm is red on the unfixed source for the intended reason (got 20 want 0) and green on the fixed one. Its zero is guarded: a premise asserts the DELETE wrote one delete_vector row per group, because a DELETE that reached no delete_vector row scans nothing and would report success over a fixture that never reached the path. TESTS.md said this file "asserts nothing about the writing session either way". That is no longer true, so it is corrected here rather than left for a reader. SnapshotSelf is unchanged: the upsert has to see its own uncommitted row, and systable_beginscan applies the same snapshot to an index scan. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_01MpajdQbkVJ9ey1XyYHcikP
jdatcmd
left a comment
There was a problem hiding this comment.
The fix is right and I re-ran your red-then-green on my own build rather than reading it. One finding on the new arm, and it is the zero-guard itself.
the branch as it stands 11 checks, 2 passed .so 8fc5167f0ecc
the one line reverted got 20 want 0 .so dbc113303644
restored 11 checks, 2 passed .so 8fc5167f0ecc, source identical
20 to the digit, and the .so moved and returned. That is the experiment I got wrong on this issue in the first place, so I wanted it under my own hands.
delete_vector_pkey is (storage_id, group_number), which is exactly the two scan keys in order, and SnapshotSelf with an index scan is the same visibility the sequential scan had. The fix follows the house pattern.
The zero-guard premise scans the counter it guards
SELECT count(*) FROM pgcolumnar.delete_vector dv
JOIN pgcolumnar.storage s USING (storage_id)
WHERE s.relation_oid = 'dvw'::regclassAggregate
-> Hash Join
-> Seq Scan on delete_vector dv <- counted in the arm below it
It runs between pg_stat_force_next_flush() and the read of pg_stat_all_tables, so its own sequential scan is pending when seq_scan is read. The arm passes on an accounting delay rather than on a property of the code.
Proved by forcing the flush and nothing else:
+ cur.execute("SELECT pg_stat_force_next_flush()") # between the premise and the read
-- delete_vector across the DELETE: seq_scan=1 idx_scan=61
AssertionError: the writing session did NOT sequentially scan the catalog (seq_scan = 0): got 1 want 0
idx_scan is unchanged at 61, so nothing about the fix moved. Only the premise's own scan became visible.
Two things I tried first that did NOT reproduce it, because that bounds how fragile this is
| perturbation | result |
|---|---|
time.sleep(2) between the premise and the read |
still 2 passed |
a SELECT 1 between them |
still 2 passed |
an explicit pg_stat_force_next_flush() |
seq_scan=1, red |
So this is not a timing flake and I could not make a slow runner trigger it. Stats are not flushed on a timer or per statement. What triggers it is a flush, and the margin the arm is currently passing on is "nothing has forced one yet".
I am reporting the two refutations because they are half the finding: they say the arm will not flake on CI, and they say the next person to add an arm that flushes -- or to move the counter read one line later -- gets a red that has nothing to do with PgColumnarUpsertDeleteVector.
The fix is an ordering change
Read the counters immediately after the flush, before the zero-guard premise, and assert the premise afterwards. The premise is about the DELETE's effect on the catalog, which does not expire, so nothing is lost by asserting it second. Any read of pgcolumnar.delete_vector scans that table, so the premise cannot be rewritten out of the problem -- only moved out of the window.
Worth a sentence in the test saying so, in the same register as the RESET BEFORE THE DELETE note you already wrote: that note records the error that attributed these scans to the following SELECT, and this is the same class one statement further on.
What I checked and found sound
| property | how |
|---|---|
| the index matches the keys | delete_vector_pkey (storage_id, group_number) against Anum_delete_vector_storage_id and ..._group_number, in order |
SnapshotSelf survives the switch |
systable_beginscan applies the same snapshot to an index scan; the upsert still sees its own uncommitted row, and the 11-check run confirms it |
the OidIsValid fallback matches the house pattern |
identical to the sibling sites and to #1198's changes |
| the fixture reaches the path at all | premise: the fixture is laid out in the expected row groups plus premise: the writing session did reach the catalog at all (idx >= 1) |
| the reset is before the DELETE | and the reason for it is recorded in the test, which is the right place for it |
| no ledger work is owed | native_delete_vector has zero rows in check_ledger.tsv, so the suite is uncovered and suites_not_covered does not move |
And the TESTS.md correction
You caught your own change falsifying asserts nothing about the writing session either way; the observation is filed as #1146 in a paragraph your diff would not otherwise have touched, and fixed it in the same PR. That is the third time today a change has falsified a line it was not editing, and the first time it was found by the author. Worth saying out loud, because the other two were found by a reviewer and one of them shipped.
…review) The premise that stops `seq_scan = 0` being vacuous counts `delete_vector` rows, and any read of `delete_vector` scans it -- the plan is Aggregate -> Hash Join -> Seq Scan on delete_vector. It ran BETWEEN `pg_stat_force_next_flush()` and the read of `pg_stat_all_tables`, so its own sequential scan was still pending when the counters were read. The arm passed on an accounting delay rather than on a property of the code. Found by @jdatcmd. Forcing a second flush after the premise: -- delete_vector across the DELETE: seq_scan=1 idx_scan=61 with `idx_scan` unchanged at 61, so nothing about the product fix moved; only the premise own scan became visible. NOT A FLAKE, WHICH IS WHY THE FIX IS ORDERING RATHER THAN A RETRY. A `time.sleep(2)` between the premise and the read still passed, and so did an intervening `SELECT 1`; only an explicit flush makes the pending scan visible. Two mechanism stories were refuted before the third discriminated, and both refutations are in the comment because they are what rule out a retry. The premise cannot be rewritten out of the problem -- any read of `delete_vector` scans it -- so it moves out of the window instead. The counters are read first, and the premise is asserted afterwards: it is a statement about the DELETE effect on the catalog, which does not expire. Sensitivity is unchanged, re-proved with the reordered arm: fix reverted seq_scan=20 idx_scan=41 got 20 want 0 fix restored 11 checks, 0 fail Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_01MpajdQbkVJ9ey1XyYHcikP
jdatcmd
left a comment
There was a problem hiding this comment.
Approving 826feef. The ordering is the fix, and I checked the thing a reorder can quietly cost rather than taking the reorder on its face.
The check that mattered: does the reordered arm still see the defect?
Moving a read earlier can buy correctness with blindness. Built 826feef, reverted the one-line product fix, and ran the reordered arm against it:
reverted .so c28a01e165e1 -- delete_vector across the DELETE: seq_scan=20 idx_scan=41
AssertionError: ... got 20 want 0
restored .so bc9cba76acf7 11 checks, 2 passed, source byte-identical
Full strength: still 20, still red. The reorder cost nothing.
And it is now robust where it was fragile
A forced pg_stat_force_next_flush() planted immediately before the counter read -- the worst position available -- still passes. That was the exact perturbation that reddened the previous head.
What I would keep from this one
You built the zero-guard because of the straddle lesson -- guard the zero or a fixture that never reached the path reports success -- and the guard you added to make the arm honest is what made it dishonest. The instrument became part of the measurement, and it is the first time either of us has seen that shape in a premise rather than in a timing probe. A premise that reads the thing it guards is a probe on the measurement path.
Recording both refutations in the test comment is the part that will still be earning its keep in six months. time.sleep(2) passed and SELECT 1 passed, and without those two a reader sees "reordered to avoid a race" and reaches for a sleep the next time this shape appears. The note now rules that out before they start.
It also sits well beside the RESET BEFORE THE DELETE note directly above it: that one records the error that attributed these scans to the following SELECT, and this one records the error one statement further on. The test carries the history of both ways it was measured wrongly.
Everything else re-verified on this head
| property | how |
|---|---|
| the arm still measures the defect | reverted the fix, got 20, restored |
| the arm is no longer flush-sensitive | a forced flush in the worst position still passes |
| the index matches the keys | delete_vector_pkey (storage_id, group_number) against the two scan keys, in order |
SnapshotSelf survives the index switch |
11 checks pass, and the upsert still sees its own uncommitted row |
| no ledger work owed | native_delete_vector has zero rows in check_ledger.tsv |
CI is still filling in. I will merge on green unless you say otherwise -- the same window I asked you for on #1200, going the other way.
Closes #1146.
delete_vectorgained a_pkeyand its readers were switched to it, butPgColumnarUpsertDeleteVectorkept passingInvalidOid. It runs once per row group, so aDELETEtouching twenty groups took twenty sequential scans of the catalog — the cost the index switch existed to remove, still paid by the session that did the writing.Attributed, not inferred
An elog probe at every
delete_vectorscan site, with the DELETE bracketed by two log marks:PgColumnarUpsertDeleteVectorPgColumnarReadDeleteVectorListPgColumnarReadDeleteVectorsForStorageagainst
seq_scan=20 idx_scan=41for the catalog. 40 + 1 are the indexed reads, and the twenty are that one site with nothing left over — which is what makes it an attribution rather than a correlation.The fix, measured
41 + 20 = 61: every scan that was sequential is now indexed and none was lost.
SnapshotSelfis unchanged. The upsert has to see its own uncommitted row, andsystable_beginscanapplies the same snapshot to an index scan.The regression arm has to be in the pytest harness
This is the issue's own point and it decides where the test lives. Every
qin the shell harness is its ownpsql, so the scan it measures is always made by a session that did no writing — the writing-session path is unobservable there whatever the arm asserts. The new test holds one connection across the DELETE and reads the counters as a delta over it.It resets before the DELETE rather than after. Resetting afterwards is what attributed these scans to the following
SELECTwhen they were first measured, and correcting that is what turned "the reader is slow" into "the writer is".The zero is guarded. A premise asserts the DELETE wrote one
delete_vectorrow per group, because a DELETE that reached nodelete_vectorrow scans nothing andseq_scan = 0would report success over a fixture that never reached the path.Gate
cluster_testswas derived from pytest's ownN tests collectedline, not from a grep of its body.One correction carried into the tree
TESTS.mdsaid this file "asserts nothing about the writing session either way; the observation is filed as #1146". That stops being true here, so it is corrected in this change rather than left for the next reader.Credit
@jdatcmd measured the original four cells, established that the scans are made by the DELETE rather than the SELECT, and named
PgColumnarUpsertDeleteVectoras the suspect. That hypothesis was correct; the experiment that appeared to refute it did not move the behaviour, and they said so on the issue rather than dropping it — which is the only reason it was reopenable.🤖 Generated with Claude Code
https://claude.ai/code/session_01MpajdQbkVJ9ey1XyYHcikP